[SVLS-9883] feat: log the duration of each cold start step by lym953 · Pull Request #1412 · DataDog/datadog-lambda-extension

lym953 · 2026-10-07T16:44:37Z

Problem

The extension's cold start duration increases from time to time, and finding the cause takes a lot of engineering time. The extension logs only the total time to ready. So, to find which step became slower, we must add temporary timers and build a test layer.

This PR

At the end of each cold start, the extension logs one debug line with the duration of each initialization step. The durations are JSON numbers in milliseconds, rounded to 2 decimals, under a cold_start object. Datadog parses them as numbers, so each step can go on a chart, or into a filter such as @cold_start.start_telemetry_listener_ms:>50. Two fields appear only when their feature is on, as described below. A real line from the test below, with AppSec off, shown here on several lines. The extension writes it as one line.

{
  "status": "DEBUG",
  "message": "DD_EXTENSION | DEBUG | Cold start step durations",
  "cold_start": {
    "total_ms": 55.46,
    "enable_logging_ms": 7.7,
    "load_aws_config_ms": 1.25,
    "create_extensions_api_client_ms": 0.86,
    "register_extension_ms": 4.71,
    "load_config_ms": 3.79,
    "wait_for_register_ms": 0.87,
    "start_dogstatsd_ms": 0.92,
    "start_telemetry_listener_ms": 39.52
  }
}

The line uses the tracing target cold_start_duration, so that #1413 can turn it on alone, without the other debug logs. The existing "Datadog Next-Gen Extension ready in Nms" line stays as it is, on the default target.

The changes in the code:

main.rs records each step's duration into a struct, ColdStartDurations, which is in the new file logger/cold_start.rs.
The extension's log formatter, which wrote only the message, also writes the f64 fields of a log event as JSON numbers. A field named cold_start.x goes into the nested cold_start object. Fields of other types are dropped, as before.
logger.rs moves to logger/mod.rs, so that the extension's logging code is in one folder.

Which steps get a field

To select the steps, I made a probe build with a timer on every initialization step. Then I ran five cold starts with it. This PR keeps these steps:

Each step that took more than 0.1 ms in one or more runs.
Two steps that took less than 0.1 ms in the test, but do slow work when a feature is on. Their fields appear only when the feature is on, so that a 0.0 does not lower the average of the functions that use the feature:
- resolve_additional_endpoint_secrets_ms: resolving additional endpoint secrets. It calls AWS when an additional endpoints secret ARN (Amazon Resource Name) is set, for example DD_ADDITIONAL_ENDPOINTS_SECRET_ARN.
- create_appsec_processor_ms: creating the AppSec processor. It builds the WAF (web application firewall) when AppSec is on.

The probe build also timed the steps that follow. Each one took less than 0.1 ms in all five runs, so this PR has no field for them:

Creating the shared HTTP client
Setting up tags
Starting the logs agent
Starting the invocation processor
Starting the trace agent
Starting the Runtime API proxy
Starting the lifecycle listener
Starting the OTLP agent

Each step has its own timer, so the step durations do not add up to the total. For example, the registration request runs in a background task at the same time as config loading. wait_for_register_ms is the time that the main task waits for it.

Testing

I built an arm64 layer of commit f0fcf610 and deployed it on a Python 3.13 arm64 function with DD_LOG_LEVEL=debug. I forced two cold starts with AppSec off, and two with DD_SERVERLESS_APPSEC_ENABLED=true. Then I read the extension's logs in CloudWatch.

Each cold start logged one "Cold start step durations" line and one "ready in" line, and no per-step lines. The durations in milliseconds:

Field	AppSec off, cold start 1	AppSec off, cold start 2	AppSec on, cold start 3	AppSec on, cold start 4
`total_ms`	55.46	57.36	77.89	72.79
`enable_logging_ms`	7.7	7.02	7.3	7.14
`load_aws_config_ms`	1.25	1.16	1.18	4.87
`create_extensions_api_client_ms`	0.86	7.7	0.87	0.87
`register_extension_ms`	4.71	4.22	9.31	4.21
`load_config_ms`	3.79	1.72	7.03	1.64
`wait_for_register_ms`	0.87	2.87	2.28	2.59
`start_dogstatsd_ms`	0.92	0.41	0.28	0.32
`create_appsec_processor_ms`	not in the line	not in the line	41.09	40.25
`start_telemetry_listener_ms`	39.52	36.03	17.47	14.7

create_appsec_processor_ms is in the line only when AppSec is on. resolve_additional_endpoint_secrets_ms is in none of the lines, because the test function has no additional endpoint secrets. A unit test checks the condition for that field, but I did not test that path on Lambda. I did not test on amd64 or FIPS builds.

Next steps:

Add logging for other things, such as log/trace/metric flushing duration.
Support using an env var to configure which log groups are on

🤖 Generated with Claude Code

datadog-official · 2026-10-07T16:49:19Z

Pipelines

_{This comment will be updated automatically if new data arrives.

🔗 Commit SHA: 9f5dd94 | Docs | View more details | Give us feedback!}

lym953 · 2026-10-07T17:52:14Z

The failure of "Lockfile Scan" job is unrelated. Will fix it in a separate PR.

Copilot

🟢 Approval recommended

The instrumentation is scoped, consistent, and introduces no identified correctness issues.

0 open findings

What changed in this PR

Adds targeted debug timing for measurable cold-start initialization steps, improving startup performance diagnostics.

Changes:

Adds a reusable duration-logging macro and cold-start tracing target.
Instruments key initialization steps and assigns the existing readiness log to the same target.

File	Description
`bottlecap/src/logger.rs`	Defines the timing macro and cold-start target.
`bottlecap/src/bin/bottlecap/main.rs`	Records durations across extension initialization.

🧠 Review effort: Balanced

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

…he cargo-audit waiver (#1414) ## Problem The "Bottlecap (Rust) / Lockfile Scan" check fails on every branch, for example #1412 and an automated dd-trace-go upgrade branch. Trivy finds advisory GHSA-2mjx-qc3c-rqvc in `rustls` 0.23.43 and exits 1. `main` will fail the same way on its next run. ## Why this PR ignores the advisory The fix is in `rustls` 0.23.45, and we cannot use that version yet: - `rustls` 0.23.45 requires `aws-lc-rs` 1.18 or later. `aws-lc-rs` 1.18 uses AWS-LC-FIPS 4.x, which has no FIPS 140-3 certification yet. Our FIPS builds must use a certified crypto module. So the team reverted the bump to 0.23.45 in #1389, and #1390 pinned `aws-lc-rs` below 1.18. - The non-FIPS builds do not use `aws-lc-rs`, but both builds use the same `Cargo.lock`, so they get the same `rustls` version. - `datadog-fips` from `serverless-components` also requires `rustls` below 0.23.45. In a copy of `main` without our own cap, `cargo update -p rustls --precise 0.23.45` fails on that requirement. #1389 accepted this risk for `cargo-audit`, where the advisory has its RustSec ID, RUSTSEC-2026-0285. The GitHub advisory links to that RustSec page. The advisory says that the handshake transcript stays authenticated, so an attacker cannot change or complete a handshake. The effect is that a peer can send in plaintext some handshake messages that must be encrypted. ## Change Trivy uses its own ignore list, `.trivyignore.yaml`, and that list did not have the advisory. This PR adds GHSA-2mjx-qc3c-rqvc to it, with the same reason. It also adds a line to `bottlecap/.cargo/audit.toml` that names the Trivy entry. Then the person who removes one ignore after the certification also removes the other. `.github/workflows/vulnerability-scan.yml` reads the same file for its daily `Cargo.lock` scan, so that scan also skips the advisory. The daily image scans in that workflow do not read the file, and this PR does not change them. ## Testing ### Steps 1. Copy `bottlecap/Cargo.lock`, `bottlecap/Cargo.toml` and `.trivyignore.yaml` into an empty directory. 2. Run Trivy with the options of the CI step: `trivy fs --scanners vuln --ignorefile .trivyignore.yaml --ignore-unfixed --exit-code 1 --format table bottlecap`. 3. Do steps 1 and 2 for `main` and for this branch. ### Result | Check | Before (`main`, `469decc8`) | After (this branch) | | --- | --- | --- | | Trivy findings | 1, GHSA-2mjx-qc3c-rqvc in `rustls` 0.23.43 | 0 | | Trivy exit code | 1 | 0 | I used the local Trivy installation, not the version and database that CI uses. The CI run on this PR is the real check. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

Add debug logs under the "cold_start_duration" tracing target for each non-trivial step before the extension is ready, and move the existing "ready in" total under the same target. Steps were chosen from five cold starts of a probe build that timed every step. Steps that took under 0.1 ms in all runs were left out, except the two that do expensive work only when a feature is on: resolving additional endpoint secrets and creating the AppSec processor. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Replace the cold-start-only helper with a log_duration! macro in the library crate, so that later duration targets (trace flush, for example) reuse it from any module. A function cannot take the target, because tracing requires it to be a constant at each call site. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

clifordshelton

Thanks for this! Per-step cold start timings will save us from building probe layers. I have two main requests, plus a few smaller ones inline.

1. Put all the timings in one JSON log line

Right now the numbers are only inside the message text, like Loading config took 1.609ms. To us that's easy to read, but to Datadog it's just a string. To put it on a chart, someone would have to write a custom parser (grok rule) for each step's message, and keep it in sync whenever a message changes. In practice that means people end up reading these logs one by one instead of graphing them.

If the timings are JSON fields instead, Datadog picks them up as numbers automatically. Then we can:

Graph each step over time, e.g. average or p99 of load_config_ms, and see right away if a release made a step slower.
Split the chart by runtime, region, architecture, or extension version to see where a slowdown happens.
Sort or filter logs by a step's duration to find the slowest cold starts, e.g. @cold_start.start_telemetry_listener_ms:>50.
Build a dashboard or monitor from them later without extra setup.

Instead, it would be better if we log all the step timings once as JSON fields on a single line and remove the separate per-step lines:

{"status":"debug",
 "message":"DD_EXTENSION | DEBUG | Cold start step durations",
 "cold_start":{"total_ms":21,"enable_logging_ms":5.84,"load_aws_config_ms":2.44,
               "load_config_ms":1.61,"wait_for_register_ms":7.19,
               "start_dogstatsd_ms":0.29,"start_telemetry_listener_ms":2.21}}

With this, a chart of @cold_start.start_telemetry_listener_ms would have shown the 63.9 ms outlier in your test table. Make sure we use numbers for the values and not strings so that it parses correctly.

To do this, logger::Formatter needs to write these extra fields into the JSON. Today it only writes status and message and drops everything else.

2. Turn these logs off by default

Your numbers in #1413 show these lines were 33 of 117 debug lines across 3 cold starts. That's a lot of extra lines (~28%) for someone using DD_LOG_LEVEL=debug to debug something else.

How about we make the cold_start_duration target off by default, even when DD_LOG_LEVEL=debug. People who need the timings can turn them on with DD_LOG_LEVEL_BY_TARGET=cold_start_duration=debug from #1413. Let's use the same rule for future targets like trace_flush_duration.

clifordshelton · 2026-10-09T20:02:37Z

    resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
+    log_duration!(
+        COLD_START_DURATION,
+        "Resolving additional endpoint secrets",


This step only does real work (calling AWS to fetch the secret) when an additional endpoints secret ARN such as DD_ADDITIONAL_ENDPOINTS_SECRET_ARN is set. For everyone else it does nothing, which is why it showed ~0 ms in all three of your cold starts. If we always record it, most functions get a field that is always ~0 and never tells us anything. It's better to only record it when that ARN is set, so when it does show up, it's meaningful.

Collapsed into a single log line.

This still applies to create_appsec_processor_ms and resolve_additional_endpoint_secrets_ms values. They're always inline even when the feature is off. So most functions will log 0.0 for them (like the example in PR description).

It would be better if we only add these two fields when the feature is enabled, and leave them out otherwise because of these reasons:

The field itself tells us if the feature was on or off. Right now 0.0 could mean "AppSec is off" or "AppSec is on and was fast" and we can't tell which one. If the field only shows up when AppSec is enabled, then just seeing it in the log tells us AppSec was on. Bonus: This will allow us to also search for something like @cold_start.create_appsec_processor_ms:* to find only the cold starts that had AppSec on.

The zeros skew the averages. Say we chart the average create_appsec_processor_ms across 100 functions and 10 of them have AppSec on at ~40 ms each. The other 90 log 0.0, so the chart shows an average of about 4 ms. That looks like nothing even though AppSec actually adds 40 ms to those cold starts. If the field is left out when AppSec is off, the average only counts the 10 real values and shows the actual 40 ms.

You can make the two fields Option<f64> and only set them when the feature is enabled. The formatter already leaves out None fields (test_formatter_omits_none_fields).

Good point. Addressed. Made resolve_additional_endpoint_secrets_ms and create_appsec_processor_ms optional.

Replace the per-step debug lines with one "Cold start step durations" line. Each step is a numeric field under a nested `cold_start` object, rounded to 2 decimals, so that Datadog can graph and filter each step. The steps are collected in a ColdStartDurations struct. It replaces the `start_time` parameter of extension_loop_active, so the function keeps 7 parameters. The registration task returns its duration with its result. logger::Formatter writes the fields of an event as JSON values, and nests a field named `group.key` under `group`. It used to drop every field except the message. No other log call passes fields. The summary line uses `event!`, because `debug!` in tracing 0.1.44 cannot parse dotted field names after `target:`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

ColdStartDurations, its log() method and elapsed_ms() move from main.rs to bottlecap::cold_start, so main.rs keeps only the timing calls. Renames: `cold_start` to `cold_start_durations`, its field `start` to `started_at`, and `step_start` to `step_started_at`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lym953 · 2026-10-15T19:04:02Z

Put all the timings in one JSON log line

Implemented

Turn these logs off by default

It's likely unnecessary now since there's only one cold_start line.

Support and engineers search for this line, and on the cold_start_duration target a DD_LOG_LEVEL_BY_TARGET entry such as `cold_start_duration=off` would hide it. The summary line already has the total as `total_ms`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

logger.rs becomes logger/mod.rs, and cold_start_log.rs becomes logger/cold_start.rs, so the formatter, the log targets and the cold start durations live together. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

The codebase names Instant values start, start_time or *_time, and has no *_at names. main.rs called the process start start_time before. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

The summary line has only f64 fields, so the formatter writes those and drops the other field types, as it did before for all fields. Strings, integers and booleans need their own record_* method when a log line first uses them. A NaN or infinite value is dropped, because JSON has no value for it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

… JSON fields_to_json builds a serde_json::Map with a nested object for each group, and serde_json writes the keys and numbers. A whole number is now written as 21.0 instead of 21. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lym953 · 2026-10-15T20:18:17Z

Addressed all the comments.

Copilot

🟢 Approval recommended

The instrumentation preserves initialization behavior, and no blocking correctness or security issues were identified.

0 open findings

🧠 Review effort: Balanced

clifordshelton

Approved. Left a comment on this thread. I think the main point of the comment got missed out in migrating code to logging a single line.

create_appsec_processor_ms is set only when AppSec is enabled, and resolve_additional_endpoint_secrets_ms only when the config has an additional endpoints secret ARN. Otherwise the fields are left out of the summary line, so that a 0.0 does not lower the average of the functions that use the feature, and the field shows that it was on. has_additional_endpoints_secrets() holds the check that resolve_additional_endpoints_secrets() used for its early return, so that main.rs and that function share it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

…-duration-logs

DD_LOG_LEVEL_BY_TARGET is a comma-separated list of `<target>=<level>` entries, such as `cold_start_duration=debug`. Each entry sets the log level of one tracing target, and DD_LOG_LEVEL stays the level of all other targets. The parsing is in datadog-serverless-logging, from serverless-components. The extension logs a warning for each entry that is not valid. The HTTP libraries h2, hyper, reqwest and rustls stay off, and an entry cannot turn them on. The extension sends its own logs to Datadog, so their logs for each request would add lines to each flush. One list, LOCKED_LOG_TARGETS, builds both their `off` rules and the locked list. The serverless-components dependencies point at the head of DataDog/serverless-components#183, which adds the locked targets. This commit replaces the earlier commits of this PR, rebuilt on top of the current #1412. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lym953 mentioned this pull request Oct 7, 2026

[SVLS-9883] feat: add DD_LOG_LEVEL_BY_TARGET to set log levels per target #1413

Open

lym953 marked this pull request as ready for review October 7, 2026 17:51

lym953 requested a review from a team as a code owner October 7, 2026 17:51

lym953 requested review from clifordshelton and a balanced review from Copilot October 7, 2026 17:51

Copilot started reviewing on behalf of lym953 October 7, 2026 17:52

View session

Copilot AI reviewed Oct 7, 2026

View reviewed changes

lym953 mentioned this pull request Oct 7, 2026

ci: ignore GHSA-2mjx-qc3c-rqvc in the Trivy lockfile scan, matching the cargo-audit waiver #1414

Merged

lym953 and others added 2 commits October 9, 2026 14:56

lym953 force-pushed the yiming.luo/cold-start-duration-logs branch from 776fb27 to acf98dd Compare October 9, 2026 18:56

clifordshelton reviewed Oct 9, 2026

View reviewed changes

lym953 and others added 2 commits October 14, 2026 14:52

lym953 and others added 6 commits October 15, 2026 15:11

[SVLS-9883] Rename the cold_start module to cold_start_log

71e0a04

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

[SVLS-9883] Move the extension's logging code into a logger/ folder

71c0efe

logger.rs becomes logger/mod.rs, and cold_start_log.rs becomes logger/cold_start.rs, so the formatter, the log targets and the cold start durations live together. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

[SVLS-9883] Name the cold start timers start_time and step_start_time

572c875

The codebase names Instant values start, start_time or *_time, and has no *_at names. main.rs called the process start start_time before. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lym953 requested review from clifordshelton and a balanced review from Copilot October 15, 2026 20:18

Copilot started reviewing on behalf of lym953 October 15, 2026 20:18

View session

Copilot AI reviewed Oct 15, 2026

View reviewed changes

clifordshelton approved these changes Oct 15, 2026

View reviewed changes

lym953 and others added 2 commits October 15, 2026 19:03

Merge remote-tracking branch 'origin/main' into yiming.luo/cold-start…

9f5dd94

…-duration-logs

gh-worker-dd-devflow-36fce6 Bot added mergequeue-status: queued mergequeue-status: in_progress and removed mergequeue-status: queued labels Oct 16, 2026

gh-worker-dd-mergequeue-cf854d Bot merged commit 8d3b993 into main Oct 16, 2026
63 checks passed

gh-worker-dd-devflow-36fce6 Bot removed the mergequeue-status: in_progress label Oct 16, 2026

gh-worker-dd-mergequeue-cf854d Bot deleted the yiming.luo/cold-start-duration-logs branch October 16, 2026 01:32

gh-worker-dd-devflow-36fce6 Bot added the mergequeue-status: done label Oct 16, 2026

Conversation

lym953 commented Oct 7, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

This PR

Which steps get a field

Testing

Next steps:

Uh oh!

datadog-official Bot commented Oct 7, 2026 • edited by datadog-datadog-us1-prod Bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lym953 commented Oct 7, 2026

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

🟢 Approval recommended

Uh oh!

clifordshelton left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

clifordshelton Oct 9, 2026

Choose a reason for hiding this comment

Uh oh!

lym953 Oct 15, 2026

Choose a reason for hiding this comment

Uh oh!

clifordshelton Oct 15, 2026

Choose a reason for hiding this comment

Uh oh!

lym953 Oct 15, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

lym953 commented Oct 15, 2026

Uh oh!

lym953 commented Oct 15, 2026

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

🟢 Approval recommended

Uh oh!

clifordshelton left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

lym953 commented Oct 7, 2026 •

edited

Loading

datadog-official Bot commented Oct 7, 2026 •

edited by datadog-datadog-us1-prod Bot

Loading